Add request phase timing: Server-Timing subtimings and access telemetry - #1074
Add request phase timing: Server-Timing subtimings and access telemetry#1074jevansnyc wants to merge 26 commits into
Conversation
* Add request phase timing design spec (Server-Timing subtimings + access telemetry) * Address review round 1: freeze point, template-cache naming, snapshot semantics, KV scope, geo carry, route template, sink confirmation, sampling and query model, config rollback * Address review round 2: auction-wait placement modes, conservative private-only header emission, non-null sorting key with service identity, coarse publisher route template, telemetry snapshot and outage behavior, tinybird flag decoupling, adapter phase semantics * Add request phase timing implementation plan * Address engineer review: KV timing decorator, try_lock sampling, route metadata extension, adapter-derived env, typed template-cache state, adapter-owned emission context, per-mode delivery semantics, Axum outer wrapper
…ite-back in middleware Three final-review fixes for access telemetry correctness: - Normalize the HTTP method to an allowlist (GET/HEAD/POST/PUT/DELETE/ PATCH/OPTIONS, else "other") inside access_event_row, so a client- controlled extension-method token can never inflate the LowCardinality method column, regardless of which adapter builds the row. - Guard emit_access_telemetry_after_send against snapshots carrying a degraded sample_rate of 0.0 (captured on the app-state-build-failure fallback path), which could otherwise be sampled in by freshly reloaded settings and corrupt the sum(1.0/sample_rate) volume estimator. - Mirror the geo lookup write-back from apply_entry_point_finalize_headers into FinalizeResponseMiddleware::handle, so a middleware-finalized response that resolved geo via fallback carries the resolved GeoLookupState for the access-telemetry snapshot instead of showing country "unknown".
|
Post-review addition from the first live full-stack test (stackpop.com staging property): commit 7cf7d86 adds JSONPaths to every access_logs_raw column and replaces the event_date DEFAULT column with a toDate(event_ts) sorting-key expression. The Events API rejects NDJSON ingestion into a datasource without JSONPaths (400, discovered live; the confirmed-delivery check surfaced it via the drop warning), and once any column has a path every column needs one, which a DEFAULT column the producer never sends cannot satisfy. Spec section 9 updated in the same commit. Verified end to end: rows now flowing guest -> Events API -> ClickHouse with correct phase attribution and route-template normalization. |
prk-Jr
left a comment
prk-Jr
left a comment
There was a problem hiding this comment.
Review summary
Verdict: Request changes.
The timing core is careful, well-reasoned work, and the Tinybird schema discipline is actually better than the PR body claims (verified below). The blocker is that this ships a reproducible crash-on-every-request regression on the Cloudflare adapter — with a one-line fix — plus a second instance of the same bug that CI structurally cannot catch, and a route normalizer that lets UUIDs, reset tokens and article slugs into a 30-day dataset.
Verification performed
Reviewed at head 7cf7d867 in a scratch worktree. Local gates, all run there:
| Gate | Result |
|---|---|
cargo fmt --all -- --check |
PASS |
cargo clippy-fastly / clippy-axum / clippy-cloudflare-wasm |
PASS |
cargo test-fastly |
PASS (2235 + 186 + 21 + 4 + 2) |
cargo test-axum |
PASS (25 + 14 + 1) |
npx vitest run |
PASS — 45 files, 871 tests, 0 failures |
gh pr checks 1074: 19 checks, 1 failing — integration tests. It is not in the branch-protection required set, so it will not block the merge button, but it is a genuine regression (root-caused inline).
Blocking
- CRITICAL —
std::time::Instantpanics onwasm32-unknown-unknown; every publisher request on Cloudflare traps. Confirmed by reproducing the failing integration test locally, capturing the workerd stack trace, applying the fix, and re-running green (15.34s fail → 1.16s pass). - HIGH — Two more
Instant::now()calls on the auction path inpublisher.rs. The integration fixture has[auction] enabled = false, so CI stays green even after finding 1 is fixed, while Cloudflare does dispatch auctions in production. - HIGH —
publisher_route_templateadmits UUIDs, opaque tokens and full article slugs into a 30-day dataset, contradicting the module's own doc comment.
Verified praise
- Schema alignment is exactly right. Parsed all four artifacts: 26 datasource columns, 26 producer keys, 26 fixture keys, 26
FORWARD_QUERYcolumns — identical names and identical order, zero set difference. try_lock-only is real. 7 lock acquisitions inrequest_timing.rs, alltry_lock, zero.lock(). No method calls another while holding its guard, so no re-entrant self-deadlock.- Saturating arithmetic is complete —
saturating_addinrecord/record_auction_wait/CountingWriter::write,try_from(..).unwrap_or(MAX)in bothduration_msandrecord_buffered_delivery. - The Server-Timing cache-control gate holds on every emit path. Both emitters funnel through
append_server_timing_if_private, andcache_control_value_has_directiveis exact-name and quote-aware (not-private/no-storeycorrectly do not match). On Fastly the call sits afterapply_terminal_response_effectsand both finalize passes, soCache-Controlis settled and nothing mutates it afterwards. [observability]back-compat is sound.Settingscarriesdeny_unknown_fieldsand the pushed blob is a serde serialization ofSettings, soskip_serializing_if = "ObservabilitySettings::is_default"genuinely keeps a default table out of the blob.TinybirdSettingshas nodeny_unknown_fieldson either side, so the newauction_enabledkey does not break rollback either.- The hand-rolled Axum
serveis behaviourally equivalent to the upstream helper it replaces (Stores::default()makes every store-attach branch a no-op; the rest is mirrored exactly).
Audit of the PR body's stated limitations
Most disclosures check out. Four do not:
| Disclosure | Verdict |
|---|---|
| "The 27 vitest failures ... will block the JS CI gate" | Stale. vitest is green on CI; locally 871 tests, 0 failures. |
| "Cloudflare and Spin collect but do not emit in v1" | Badly understated. Spin is fine (wasm32-wasip1, std Instant works). Cloudflare does not collect — it traps on every publisher request. |
"sorting key (event_date, service_id, ...)" |
Inaccurate. Actual key is toDate(event_ts), service_id, ...; event_date is not a column at all. |
| Failing Cloudflare integration job | Unmentioned, and failing on all three runs of the branch. |
Accurate as written: deploy/rollback ordering and the older-binary rejection mechanism (verified end to end), column-for-column schema alignment, the inspection-only Tinybird caveat and incompatible sorting-key change, Axum header-only semantics, DeliveryResult collected-but-unemitted, and the buffered-path request_elapsed_ms placement.
One nuance: "infallible by construction ... no panics" is accurate on locking and arithmetic, but slightly overstated given the unchecked phases[index] array access (noted inline, non-blocking).
std::time::Instant::now() panics on wasm32-unknown-unknown, so every publisher request on the Cloudflare adapter trapped when the timing collector was constructed, and the two auction-wait sites would trap once an auction dispatched. web_time re-exports std's Instant on every other target, so Fastly, Axum, and Spin behavior is unchanged. The publisher.rs sites are qualified locally because that module's std Instant import still serves the pre-existing template-cache sites, which are out of scope here.
The character allowlist alone does not bound identity: [a-z0-9_-] is exactly the alphabet UUIDs, hex ids, reset tokens, and article slugs are built from, and truncating to 32 characters still leaves a globally unique prefix. A first segment now rejects whole to /other/* when it exceeds 32 characters or carries more than 7 ASCII digits, alongside the existing charset rejection. Year archives and hyphenated section names still pass. Extends the adversarial tests to the publisher-fallback path with UUID, hex-id, token, and slug shapes, and fixes the stale event_date reference in the row-builder doc.
- Gate building the access snapshot on tinybird.enabled and access_enabled, threaded through SendContext: a disabled deployment (the default) no longer pays env reads and String allocations on the pre-send path. DeliveryOutcome.snapshot becomes Option and the emitter treats None as nothing to send. - Classify asset-fallback responses as route_class asset with the operator-configured route prefix as the template, instead of landing in the other/unknown bucket alongside 404s. - Pin Phase::index() to PHASE_COUNT with a uniqueness-and-bounds test so a future variant fails the suite instead of panicking at runtime. - Drop the tautological sampled-out emission test; the 0.0-rate behavior is covered by sampled_in_boundary_rates_are_unconditional. - Clarify that the local dev config env var name genuinely triples trusted_server_config (prefix, store, key) rather than reading as a find/replace mistake.
ChristianPavilonis
left a comment
ChristianPavilonis
left a comment
There was a problem hiding this comment.
Summary
👍 Reviewed the exact head revision 38043d7464362d44519153a09fe850bacc256b58. The overall implementation direction is solid and all reported CI checks pass. I left seven actionable inline findings: three P2 telemetry-correctness issues and four P3 design/test-cleanup issues. There are no P0 or P1 findings.
ChristianPavilonis
left a comment
ChristianPavilonis
left a comment
There was a problem hiding this comment.
Summary
🔧 Superseding my prior approval for 38043d7464362d44519153a09fe850bacc256b58: please address the seven inline findings already posted in the preceding review, particularly the three P2 telemetry-correctness issues, before merge. The existing inline threads remain the actionable review details and are not duplicated here.
prk-Jr
left a comment
prk-Jr
left a comment
There was a problem hiding this comment.
Summary
Substantial, carefully-built observability layer: 27 files, ~6.5k insertions, with a
freeze-point design that reads typed response extensions rather than the headers they
back, symmetric geo write-back on both finalize sites, and adversarial route-template
tests. All 19 GitHub checks pass and I reproduced every CI gate locally (2450 Fastly +
40 Axum + 39 Cloudflare + 79 Spin + 13 parity Rust tests, 871 JS tests).
One blocking finding, and it is a spec-conformance question rather than a crash risk:
publisher_route_template does not meet section 9 of
docs/superpowers/specs/2026-08-24-request-phase-timing-design.md for single-segment
paths. Everything else below is non-blocking.
I also checked the access sampler for modulo bias and it came back clean — see the
note in the cross-cutting section, since it is the kind of thing worth recording as
verified rather than leaving as an open question.
4 of the inline comments below carry a one-click GitHub
suggestion. I applied all
four together in a scratch worktree at this head and verified them:
cargo fmt --all -- --checkPASS,cargo clippy-fastlyPASS (0 warnings),
trusted-server-corelib 2238 passed / 0 failed,trusted-server-adapter-fastly
185 passed / 0 failed.
Blocking
🔧 wrench
publisher_route_templatekeeps single-segment article slugs verbatim, against spec section 9 — inline atcrates/trusted-server-core/src/access_telemetry.rs:189
Non-blocking
🤔 thinking
Server-Timingis an unrestricted client-visible latency oracle when enabled — inline atcrates/trusted-server-core/src/request_timing.rs:285
♻️ refactor
HEADER_PHASESis a second hand-synced list with no test — inline atcrates/trusted-server-core/src/request_timing.rs:419#[allow(dead_code)]on the wholeDeliveryOutcomemasks two live fields — inline atcrates/trusted-server-adapter-fastly/src/main.rs:571
🏕 camp site
route_class_renders_snake_caseomits the newAssetvariant — inline atcrates/trusted-server-core/src/access_telemetry.rs:526
⛏ nitpick
- Test name asserts the opposite of what it tests — inline at
crates/trusted-server-core/src/access_telemetry.rs:439
👍 praise
- Freeze point reads extensions, not headers — inline at
crates/trusted-server-adapter-fastly/src/main.rs:797
Cross-cutting
-
✅ Checked and clean: the access sampler is not modulo-biased.
entropy = since_epoch.as_nanos() as u64 ^ outcome.bytesthenentropy % 1_000_000 < rate * 1e6looks like it could starve whole response-size classes, because the guest wall clock is microsecond-resolution andnanosis therefore always a multiple of 1000. It does not:as_nanos()since epoch is a ~61-bit monotonically advancing value, and% 1_000_000folds the high bits back in, so residues walk the whole bucket range across requests. Measured at n=200,000 per size against the binomial 3σ band, with the clock spread over a realistic arrival window: fixed sizes of 200 B, 4 KB, 64 KB, 100 KB, ~1 MB and 1.5 MB all land inside the band at bothaccess_sample_rate = 0.05and0.01; 0/400 random sizes are ever starved. Freezing the clock inside a single millisecond does produce an apparent bias, but that is an artifact of collapsing the reachable residue set, not a property of the sampler. No change wanted here —sampled_in's "approximately even, not provably unbiased" doc comment is accurate as written. -
📌
std::time::Instant::now()still traps onwasm32-unknown-unknownin ~15 pre-existing core sites. This PR correctly moved its own timing paths toweb_time, and #1075 tracks two of the neighbours — but the set is wider than that issue records:crates/trusted-server-core/src/auction/orchestrator.rs(lines 101, 295, 332, 375, 509, 581, 978, 1045, 1348),crates/trusted-server-core/src/auction/telemetry.rs:178,202,crates/trusted-server-core/src/integrations/datadome/protection_scope.rs:405,435, andcrates/trusted-server-core/src/publisher.rs:2259,4734(the template-cache TTL sites the new comments explicitly point at). Out of scope to change here; worth widening #1075's scope so the Cloudflare auction, DataDome-scope and template-cache-TTL paths are not left believed-covered. -
📝 The Axum adapter now hand-rolls
AxumDevServer's serve loop.crates/trusted-server-adapter-axum/src/main.rsreplacesAxumDevServer::with_config(router, config).run()with a localrun/servepair. Diffed against the pinned rev (edgezerotagv0.0.4,9e661ae,crates/edgezero-adapter-axum/src/dev_server.rs:274-321) and it is faithful:AxumDevServerConfighas exactlyaddrandenable_ctrl_cand both are honoured,serve_with_storeswithStores::default()inserts nothing extra, and theRouter::new().fallback_service(service_fn(...))+into_make_service_with_connect_info::<SocketAddr>()shape matches line for line. Only deviation istokio::net::TcpListener::bindwhere upstream binds astdlistener and callsfrom_std— behaviourally equivalent here. No finding against the code as written; the note is drift risk, since this copy will silently diverge at the nextedgezerorepin. Upstreaming a service-layer hook (AxumDevServer::with_service_layer) would let the fork go away. -
📝 Phase spans are not disjoint, so header subtimings do not partition
ts-total.Phase::Streamdeliberately encloses the in-stream auction wait —stream_drive_records_stream_ms_covering_the_in_stream_auction_waitassertsstream_ms >= auction_wait_ms— and every span is RAII across.await, so it measures wall clock including suspension rather than work. Both are the right choices for stall diagnosis, butdocs/guide/configuration.md's new "Observability" section reads as if the entries were a breakdown. One sentence saying the entries may overlap and do not sum tots-totalwould stop an operator drawing the wrong conclusion from the header. -
📝
ObservabilitySettings' rollback doc attributes the protection to the wrong attribute.crates/trusted-server-core/src/settings.rssays ofObservabilitySettings: "this struct denies unknown fields, so an older binary loading a config blob carrying an[observability]table it does not know would reject it, breaking rollback." The mechanism that actually makes rollback unsafe is#[serde(deny_unknown_fields)]onSettingsitself (settings.rs:2653) in the older binary;ObservabilitySettings' own attribute only rejects unknown keys inside the table in the new binary. The conclusion and theskip_serializing_if = "ObservabilitySettings::is_default"guard are both correct — only the stated reason is off, and it would mislead the next reader who tries to relax either attribute.
Verification performed
Scratch worktree at PR head 38043d74:
| Gate | Result |
|---|---|
gh pr checks 1074 |
19/19 PASS, 0 failing, 0 pending |
cargo fmt --all -- --check |
PASS |
cargo clippy-fastly / -axum / -cloudflare / -cloudflare-wasm / -spin-native / -spin-wasm |
PASS (all six) |
cargo test-fastly |
PASS — 2450 passed, 0 failed, 10 ignored |
cargo test-axum |
PASS — 40 passed, 0 failed |
cargo test-cloudflare |
PASS — 39 passed, 0 failed |
cargo test-spin |
PASS — 79 passed, 0 failed |
| parity suite | PASS — 13 passed, 0 failed |
npx vitest run |
PASS — 45 files, 871 tests, 0 failed |
Could not verify
- Fastly Compute production wall-clock granularity — the microsecond resolution behind the sampler check was measured under Viceroy on
wasm32-wasip1, not on Fastly Compute. The clean result holds for any granularity finer than a millisecond, so this does not change the conclusion. - Cloudflare
web_time::Instantbehaviour on workerd — no workerd here; taking the description's word that it was verified. Worth noting Workers deliberately freezes clocks between I/O, so CPU-only phases will likely read0there. Harmless while Cloudflare does not emit, but the collected values are not usable as-is if emission is turned on later. - Tinybird schema deployment state —
ENGINE_SORTING_KEYchanged incompatibly from the reserved schema; whetheraccess_logs_rawwas ever deployed remotely (and so whether this needs a versioned replacement plus cutover rather than an in-place edit) is a live-account question. Already disclosed as a rollout precondition; notbCLI here. - Fronting delivery layer
Server-Timingpass-through — needs a staging deploy; already disclosed. emit_access_eventagainst real Tinybird — exercised only through the recording double, so the live ingest contract is unverified.
The first path segment is only a section name when the path has depth: under a /%postname%/ permalink structure every article is a single-segment path, so keeping those segments verbatim put full article slugs into the 30-day dataset, against spec section 9. Depth is now required for a named template; single-segment paths, root landing pages included, bucket to /other/*. Route slicing keeps route_class and multi-segment templates like /news/*.
The bucket-quantized sampler truncated rates below one in a million to a zero threshold (silently emitting nothing) and quantized other low rates downward while rows still carried the configured rate, biasing the sum(1.0 / sample_rate) volume estimator. Its no-rand premise was also wrong: rand::thread_rng() is WASI-backed on this target and the EC generation path already relies on it. The sampler is now a direct uniform-roll comparison, and the roll gates on the rate stored in the snapshot itself, so emission probability and the row's sample_rate column cannot diverge; the divergence guard and its tests are removed. Also per review: the settings-reload fallback in the post-send path could never emit (no snapshot exists when settings were absent) and is removed; the dead_code allow on DeliveryOutcome narrows to the one collected-but-unemitted field; and the post-send ordering test is narrowed to the leg it actually proves, that request_elapsed is stamped when send returns.
On origin failure with a dispatched auction, the origin span guard stayed alive through the emit_abandoned_auction await, so ts-origin and origin_ms absorbed Tinybird emission time. The span now closes when the send resolves, before either branch, with an error-path regression test.
- Pin HEADER_PHASES against Phase::header_name() in the phase-index test, closing the second hand-synced list. - Add RouteClass::Asset to the snake_case rendering test; rename the lowercasing test to say what it does. - Give the Axum adapter a named, fully configured construction path (TrustedServerApp::dev_server_service) so server_timing_enabled is never silently discarded; the tuple API is private now. - Document that Server-Timing is client-visible when enabled, in the configuration guide's observability section. - Replace stale event_date references in the spec, plan, and dashboard guidance with the toDate(event_ts) sorting-key expression, and state the single-segment rejection rule in spec section 9.
…ming # Conflicts: # crates/trusted-server-adapter-fastly/src/app.rs # crates/trusted-server-adapter-fastly/src/main.rs # crates/trusted-server-adapter-fastly/src/middleware.rs # crates/trusted-server-core/src/publisher.rs # crates/trusted-server-core/src/settings.rs # docs/guide/configuration.md # trusted-server.example.toml
The access emitter carried the configured body limit without enforcing it, allowing oversized rows to bypass the intended transport safeguard.
4 participants
Closes #1068. Implements the design in #1069 (
docs/superpowers/specs/2026-08-24-request-phase-timing-design.md); the implementation plan and the spec ride in the branch.What this adds
RequestTimings(core): always-on per-request phase collection;try_lock-only, saturating, infallible by construction.Server-Timingheader (ts-total,ts-appbuild,ts-filter,ts-geo,ts-kv,ts-origin,ts-template-cache) emitted at the send freeze point immediately beforeinto_parts(), gated byobservability.server_timing_enabledand restricted to conclusively private (private/no-store) responses so no shared cache can replay timings.TimedKvStoredecorator implementing bothPlatformKvStoreandEcKvStore(latency-only; reads no payloads). Pull-sync stores are explicitly untimed.GeoLookupStateresponse extension (NotAttempted/Attempted/Resolved), 401 rule preserved.DeliveryResult::{Complete, Partial, Error}), auction-wait with explicit placement (in_streamat the seam,pre_headeron buffered paths), response bytes, and a post-bodyrequest_elapsed_msthat excludes pull-sync and telemetry.AccessTelemetrySnapshotbuilt unconditionally at the freeze point, coarse PII-safe route templates (allowlist-reject; adversarially tested with EC ids, emails, search terms), and a confirmed-delivery Tinybird sink (bounded await, 2xx-validated, sampled bytinybird.access_sample_rate) that runs after client delivery and after pull-sync.access_logs_rawschema aligned column-for-column with the row producer; sorting key(toDate(event_ts), service_id, publisher_domain, env, route_class, pop, status); there is noevent_datecolumn (Tinybird's Events API requires a JSONPath on every column, which a derived-default column cannot carry).docs/guide/configuration.md.Review process
Eleven plan tasks, each implemented and passed an independent task-scoped review; two task-level fix rounds (settings validation coverage; a schema/producer nullability mismatch caught before it could quarantine rows at ingestion); a final whole-branch review on the full 13-commit diff followed by one fix wave (method-token normalization, a zero-sample-rate guard, geo write-back symmetry) and a clean scoped re-review.
Known limitations and rollout preconditions (disclosures)
access_logs_rawwas ever deployed remotely: the sorting key changed incompatibly from the reserved schema, so a deployed datasource means a versioned replacement with cutover, not an in-place edit. Panel queries needEXPLAINvalidation against the new key.[observability]table.ts-appbuild); Cloudflare and Spin collect but do not emit in v1. An earlier revision of this branch usedstd::time::Instant, which panics onwasm32-unknown-unknownand trapped every Cloudflare publisher request (the failingintegration testsruns on this branch); the timing paths now useweb_time::Instant, verified against the real workerd runtime locally.DeliveryResultis collected but not yet emitted on any surface (intentional groundwork).Partialsemantics are error-based only, per an explicit owner ruling: clean-but-early source truncation is out of scope permanently.request_elapsed_msis stamped beforesend_to_client(no drive to time); streaming responses, the case that matters for stall diagnosis, include the full drive.access_sample_rate = 1.0is a diagnosis setting, not a steady state.Generated with Claude Code